PROF-1037: Capture thread CPU time elapsed in scope by jbachorik · Pull Request #1358 · DataDog/dd-trace-java

jbachorik · 2020-04-09T17:30:31Z

Add thread CPU time elapsed while the scope was active to the Scope event.

Thread CPU time is comparatively cheap to obtain (~300ns per inocation) so we should be able to enhance the Scope event with the amount of CPU time spent in each recorded scope.

…tion

devinsba

Makes sense to me. We might want to check that JFR is supported before making the initialize call to save a class load

mar-kolya · 2020-04-15T19:26:31Z


+  @Label("Thread CPU Time")
+  @Timespan
+  private volatile long cpuTime = 0L;


My impression is that scopes are locked to given thread - is there any point in this being volatile?

If it is guaranteed that the event is created and committed from the same thread then this does not need to be volatile. I just wasn't sure there was such a guarantee.

mar-kolya

It would be really great to have new code tested.

In addition to requests already mentioned in the comments I think it would be possible to have integration test for profiling improved to have some verification that we are getting reasonable data in new event.

jbachorik · 2020-04-16T09:00:34Z

@devinsba The check would be quite tricky without reworking the initialization logic in Agent/ProfilingAgent.

In the current implementation we first fire up ProfilingAgent initialization and only then we run (possibly asynchronous) JMX etc. initialization blocks.
The ThreadCpuTime.initialize() routine needs to run within JMX initialization block to make sure we are not triggering JMX initialization at wrong time. But we should not be attempting to touch JFR classes from Agent itself since all interaction with JFR should be done in ProfilingAgent.
However, ProfilingAgent has no idea about JMX etc. initialization. It is kind of chicken&egg problem.

I would really like to avoid major rewrite of initialization protocol for Agent in this PR. If there is a simple way to achieve the JFR check which would not possibly screw up JMX initialization I am not seeing, please advice.

EDIT: Actually, scratch this. I was able to come up with something simple with @mar-kolya help so we might be good to go regarding not loading this class unnecessarily.

… cpu time at all

mar-kolya · 2020-04-17T11:49:11Z

+     * Initialize the thread cpu time provider only if profiling is enabled.
+     * ATTENTION! If ever is the thread cpu time provider used outside of profiler this check should be revisited.
+     */
+    if (Config.get().isProfilingEnabled()) {


We do not use Config here - and IIRC there are awkward implications for doing that. Could you please move this check into datadog.trace.common.util.ThreadCpuTimeAccess#enableJmx?

Well, I thought the idea was to avoid loading that class at all :)

mar-kolya · 2020-04-17T12:17:30Z

+          attribute = k
+        }
+    }
+    return attribute


Would def accessor = Attribute.attr("cpuTime", UnitLookup.TIMESPAN).getAccessor(scopeEventIterable.type) work instead of this?

D'oh ... Yes, it works.

mar-kolya · 2020-04-17T15:09:27Z

LGTM assuming it builds

tylerbenson · 2020-04-17T16:17:36Z

    end();
    if (shouldCommit()) {
+      if (cpuTime > 0) {
+        cpuTime = ThreadCpuTimeAccess.getCurrentThreadCpuTime() - cpuTime;


Any risk of finish() being called more than once?

It is called solely from ContinuableScope.close() so as long as that scope is not closed multiple times we are fine.

I'd say that if this happens things will not blow up but data we produce would be off. But arguably this is the best we can do in this situation anyway.

Initial implementation of thread cpu time per scope

4d0d36e

mar-kolya reviewed Apr 9, 2020

View reviewed changes

Comment thread dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java Outdated

jbachorik added 4 commits April 9, 2020 20:55

Play nicely also with JVMs eagerly resolving constant pool symbols

9bd8d14

Do not include the time spent in handling ThreadCpuTime in event dura…

c9dad48

…tion

Do not use extra field in event

1511296

Fix formatting

7597450

jbachorik changed the title ~~Initial implementation of thread cpu time per scope~~ PROF-1037: Capture thread CPU time elapsed in scope Apr 15, 2020

jbachorik added 2 commits April 15, 2020 18:35

Formatting

551e331

Capture thread CPU time diff only when the event is about to commit

d283b3e

jbachorik marked this pull request as ready for review April 15, 2020 16:37

jbachorik requested a review from a team as a code owner April 15, 2020 16:37

devinsba approved these changes Apr 15, 2020

View reviewed changes

mar-kolya reviewed Apr 15, 2020

View reviewed changes

Comment thread dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java Outdated

mar-kolya suggested changes Apr 15, 2020

View reviewed changes

Comment thread dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ScopeEvent.java

Comment thread dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java Outdated

mar-kolya reviewed Apr 15, 2020

View reviewed changes

Comment thread dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java Outdated

mar-kolya reviewed Apr 15, 2020

View reviewed changes

Comment thread dd-java-agent/agent-bootstrap/src/main/java/datadog/trace/bootstrap/Agent.java

jbachorik added 2 commits April 16, 2020 10:30

cpuTime field does not need to be volatile

d579738

Improve test coverage

91a4146

Move ThreadCpuTime to Java 7 only location

f59cf0e

mar-kolya reviewed Apr 16, 2020

View reviewed changes

Comment thread dd-trace-ot/jfr-openjdk/src/main/java/datadog/opentracing/jfr/openjdk/ThreadCpuTime.java Outdated

Modify the mode of the CPU time provider initialization

e1350c2

jbachorik requested a review from a team as a code owner April 16, 2020 14:32

jbachorik added 2 commits April 16, 2020 16:52

Do not initialize the thread if profiling is not enabled

e41bafc

Make the cpu time assertion more lenient - some events might not have…

e43088e

… cpu time at all

mar-kolya reviewed Apr 16, 2020

View reviewed changes

Comment thread ...on-tests/src/test/groovy/datadog/smoketest/ProfilingIntegrationContinuousProfilesTest.groovy Outdated

Allow more predictable cpu time check in the integration test

a992b16

mar-kolya reviewed Apr 17, 2020

View reviewed changes

Comment thread dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeAccess.java

mar-kolya reviewed Apr 17, 2020

View reviewed changes

Comment thread dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeProvider.java Outdated

Address review comments

17c01c6

mar-kolya reviewed Apr 17, 2020

View reviewed changes

Comment thread dd-trace-ot/src/main/java/datadog/trace/common/util/ThreadCpuTimeAccess.java Outdated

jbachorik added 2 commits April 17, 2020 17:01

Change log level

2515520

Simplification in the integration smoke test

ac70cad

mar-kolya approved these changes Apr 17, 2020

View reviewed changes

Fix failing tests

ea821f0

devinsba self-requested a review April 17, 2020 15:56

devinsba approved these changes Apr 17, 2020

View reviewed changes

jbachorik merged commit 185ad18 into master Apr 17, 2020

jbachorik deleted the jb/PROF-1307_Scope_event_cpu_time branch April 17, 2020 16:14

tylerbenson reviewed Apr 17, 2020

View reviewed changes

tylerbenson added this to the 0.49.0 milestone Apr 17, 2020

Conversation

jbachorik commented Apr 9, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

devinsba left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

mar-kolya left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

jbachorik commented Apr 16, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

mar-kolya commented Apr 17, 2020

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

jbachorik commented Apr 9, 2020 •

edited

Loading

jbachorik commented Apr 16, 2020 •

edited

Loading